-
Notifications
You must be signed in to change notification settings - Fork 467
feat(profiling): add threading.RLock support to the Lock profiler (re-entrant lock) #14823
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Conversation
|
|
944b340 to
c17cd90
Compare
Bootstrap import analysisComparison of import times between this PR and base. SummaryThe average import time from this PR is: 249 ± 5 ms. The average import time from base is: 251 ± 6 ms. The import time difference between this PR and base is: -2.0 ± 0.2 ms. Import time breakdownThe following import paths have shrunk:
|
Performance SLOsComparing candidate vlad/lock-profiler-add-rlock (1db7591) with baseline main (b433817) 🟡 Near SLO Breach (4 suites)🟡 djangosimple - 30/30✅ appsecTime: ✅ 20.489ms (SLO: <22.300ms -8.1%) vs baseline: +0.4% Memory: ✅ 65.259MB (SLO: <67.000MB -2.6%) vs baseline: +4.9% ✅ exception-replay-enabledTime: ✅ 1.345ms (SLO: <1.450ms -7.2%) vs baseline: +0.2% Memory: ✅ 64.601MB (SLO: <67.000MB -3.6%) vs baseline: +4.8% ✅ iastTime: ✅ 20.409ms (SLO: <22.250ms -8.3%) vs baseline: -0.1% Memory: ✅ 65.245MB (SLO: <67.000MB -2.6%) vs baseline: +5.0% ✅ profilerTime: ✅ 15.537ms (SLO: <16.550ms -6.1%) vs baseline: +1.9% Memory: ✅ 53.772MB (SLO: <54.500MB 🟡 -1.3%) vs baseline: +4.9% ✅ resource-renamingTime: ✅ 20.605ms (SLO: <21.750ms -5.3%) vs baseline: +0.5% Memory: ✅ 65.197MB (SLO: <67.000MB -2.7%) vs baseline: +4.9% ✅ span-code-originTime: ✅ 25.052ms (SLO: <28.200ms 📉 -11.2%) vs baseline: -1.7% Memory: ✅ 67.854MB (SLO: <69.500MB -2.4%) vs baseline: +5.0% ✅ tracerTime: ✅ 20.438ms (SLO: <21.750ms -6.0%) vs baseline: ~same Memory: ✅ 65.216MB (SLO: <67.000MB -2.7%) vs baseline: +4.9% ✅ tracer-and-profilerTime: ✅ 22.709ms (SLO: <23.500ms -3.4%) vs baseline: +3.3% Memory: ✅ 66.765MB (SLO: <67.500MB 🟡 -1.1%) vs baseline: +5.1% ✅ tracer-dont-create-db-spansTime: ✅ 19.361ms (SLO: <21.500ms -9.9%) vs baseline: ~same Memory: ✅ 65.235MB (SLO: <66.000MB 🟡 -1.2%) vs baseline: +4.9% ✅ tracer-minimalTime: ✅ 16.652ms (SLO: <17.500ms -4.8%) vs baseline: ~same Memory: ✅ 65.233MB (SLO: <66.000MB 🟡 -1.2%) vs baseline: +4.9% ✅ tracer-nativeTime: ✅ 20.451ms (SLO: <21.750ms -6.0%) vs baseline: ~same Memory: ✅ 71.133MB (SLO: <72.500MB 🟡 -1.9%) vs baseline: +4.7% ✅ tracer-no-cachesTime: ✅ 18.496ms (SLO: <19.650ms -5.9%) vs baseline: +0.3% Memory: ✅ 65.201MB (SLO: <67.000MB -2.7%) vs baseline: +4.9% ✅ tracer-no-databasesTime: ✅ 18.729ms (SLO: <20.100ms -6.8%) vs baseline: -0.1% Memory: ✅ 65.201MB (SLO: <67.000MB -2.7%) vs baseline: +4.8% ✅ tracer-no-middlewareTime: ✅ 20.189ms (SLO: <21.500ms -6.1%) vs baseline: +0.2% Memory: ✅ 65.220MB (SLO: <67.000MB -2.7%) vs baseline: +4.9% ✅ tracer-no-templatesTime: ✅ 20.247ms (SLO: <22.000ms -8.0%) vs baseline: -0.1% Memory: ✅ 65.198MB (SLO: <67.000MB -2.7%) vs baseline: +4.8% 🟡 errortrackingdjangosimple - 6/6✅ errortracking-enabled-allTime: ✅ 18.072ms (SLO: <19.850ms -9.0%) vs baseline: +0.3% Memory: ✅ 65.140MB (SLO: <66.500MB -2.0%) vs baseline: +4.8% ✅ errortracking-enabled-userTime: ✅ 18.056ms (SLO: <19.400ms -6.9%) vs baseline: ~same Memory: ✅ 65.115MB (SLO: <66.500MB -2.1%) vs baseline: +4.9% ✅ tracer-enabledTime: ✅ 17.962ms (SLO: <19.450ms -7.7%) vs baseline: -0.3% Memory: ✅ 65.254MB (SLO: <66.500MB 🟡 -1.9%) vs baseline: +4.8% 🟡 flasksimple - 18/18✅ appsec-getTime: ✅ 4.575ms (SLO: <4.750ms -3.7%) vs baseline: -0.5% Memory: ✅ 61.971MB (SLO: <65.000MB -4.7%) vs baseline: +5.0% ✅ appsec-postTime: ✅ 6.604ms (SLO: <6.750ms -2.2%) vs baseline: -0.3% Memory: ✅ 61.932MB (SLO: <65.000MB -4.7%) vs baseline: +4.6% ✅ appsec-telemetryTime: ✅ 4.580ms (SLO: <4.750ms -3.6%) vs baseline: -0.4% Memory: ✅ 61.985MB (SLO: <65.000MB -4.6%) vs baseline: +4.9% ✅ debuggerTime: ✅ 1.859ms (SLO: <2.000ms -7.1%) vs baseline: -0.2% Memory: ✅ 45.416MB (SLO: <47.000MB -3.4%) vs baseline: +4.9% ✅ iast-getTime: ✅ 1.862ms (SLO: <2.000ms -6.9%) vs baseline: -0.4% Memory: ✅ 42.389MB (SLO: <49.000MB 📉 -13.5%) vs baseline: +5.1% ✅ profilerTime: ✅ 1.910ms (SLO: <2.100ms -9.0%) vs baseline: -0.3% Memory: ✅ 46.537MB (SLO: <47.000MB 🟡 -1.0%) vs baseline: +4.8% ✅ resource-renamingTime: ✅ 3.365ms (SLO: <3.650ms -7.8%) vs baseline: -0.3% Memory: ✅ 52.370MB (SLO: <53.500MB -2.1%) vs baseline: +5.0% ✅ tracerTime: ✅ 3.356ms (SLO: <3.650ms -8.0%) vs baseline: -0.2% Memory: ✅ 52.278MB (SLO: <53.500MB -2.3%) vs baseline: +4.9% ✅ tracer-nativeTime: ✅ 3.364ms (SLO: <3.650ms -7.8%) vs baseline: +0.1% Memory: ✅ 58.317MB (SLO: <60.000MB -2.8%) vs baseline: +4.9% 🟡 telemetryaddmetric - 30/30✅ 1-count-metric-1-timesTime: ✅ 2.936µs (SLO: <20.000µs 📉 -85.3%) vs baseline: -0.4% Memory: ✅ 32.126MB (SLO: <34.000MB -5.5%) vs baseline: +4.6% ✅ 1-count-metrics-100-timesTime: ✅ 203.683µs (SLO: <220.000µs -7.4%) vs baseline: +0.9% Memory: ✅ 32.165MB (SLO: <34.000MB -5.4%) vs baseline: +4.9% ✅ 1-distribution-metric-1-timesTime: ✅ 3.321µs (SLO: <20.000µs 📉 -83.4%) vs baseline: +0.7% Memory: ✅ 32.204MB (SLO: <34.000MB -5.3%) vs baseline: +5.2% ✅ 1-distribution-metrics-100-timesTime: ✅ 213.446µs (SLO: <220.000µs -3.0%) vs baseline: -0.3% Memory: ✅ 32.106MB (SLO: <34.000MB -5.6%) vs baseline: +4.6% ✅ 1-gauge-metric-1-timesTime: ✅ 2.241µs (SLO: <20.000µs 📉 -88.8%) vs baseline: +1.0% Memory: ✅ 32.086MB (SLO: <34.000MB -5.6%) vs baseline: +4.7% ✅ 1-gauge-metrics-100-timesTime: ✅ 137.935µs (SLO: <150.000µs -8.0%) vs baseline: +0.2% Memory: ✅ 32.126MB (SLO: <34.000MB -5.5%) vs baseline: +4.5% ✅ 1-rate-metric-1-timesTime: ✅ 3.256µs (SLO: <20.000µs 📉 -83.7%) vs baseline: +6.4% Memory: ✅ 32.145MB (SLO: <34.000MB -5.5%) vs baseline: +4.9% ✅ 1-rate-metrics-100-timesTime: ✅ 217.010µs (SLO: <250.000µs 📉 -13.2%) vs baseline: +0.5% Memory: ✅ 32.145MB (SLO: <34.000MB -5.5%) vs baseline: +4.9% ✅ 100-count-metrics-100-timesTime: ✅ 20.603ms (SLO: <22.000ms -6.4%) vs baseline: +1.0% Memory: ✅ 32.106MB (SLO: <34.000MB -5.6%) vs baseline: +4.7% ✅ 100-distribution-metrics-100-timesTime: ✅ 2.287ms (SLO: <2.300ms 🟡 -0.6%) vs baseline: +0.4% Memory: ✅ 32.224MB (SLO: <34.000MB -5.2%) vs baseline: +4.8% ✅ 100-gauge-metrics-100-timesTime: ✅ 1.407ms (SLO: <1.550ms -9.2%) vs baseline: -0.4% Memory: ✅ 32.145MB (SLO: <34.000MB -5.5%) vs baseline: +5.0% ✅ 100-rate-metrics-100-timesTime: ✅ 2.226ms (SLO: <2.550ms 📉 -12.7%) vs baseline: -0.5% Memory: ✅ 32.106MB (SLO: <34.000MB -5.6%) vs baseline: +5.0% ✅ flush-1-metricTime: ✅ 4.562µs (SLO: <20.000µs 📉 -77.2%) vs baseline: +3.0% Memory: ✅ 32.106MB (SLO: <34.000MB -5.6%) vs baseline: +4.9% ✅ flush-100-metricsTime: ✅ 173.957µs (SLO: <250.000µs 📉 -30.4%) vs baseline: ~same Memory: ✅ 32.126MB (SLO: <34.000MB -5.5%) vs baseline: +4.7% ✅ flush-1000-metricsTime: ✅ 2.112ms (SLO: <2.500ms 📉 -15.5%) vs baseline: -0.8% Memory: ✅ 32.893MB (SLO: <34.500MB -4.7%) vs baseline: +4.7%
|
195b3c8 to
22f1608
Compare
cbe5cdd to
a7fb6e2
Compare
0520a6b to
4c62a2c
Compare
79da982 to
3f50634
Compare
3f50634 to
7e7549f
Compare
435e9ec to
5faff64
Compare
Can you share an example of something concerning about this fact? In my view, this is actually a desired effect: complex primitives that use Lock in their implementation, such as Condition and Event, should correctly attribute time spent creating / calling both complex and simple primitives (e.g. by including the calls
I'm still fleshing this out, but given the above statement, I plan to modify Example: Option 1 , where Option 1 In fact, this approach should work for all of the complex primitives that are implemented with either Notes
Types implementing |
taegyunkim
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The PR looks mostly good.
One thing to check
- How these samples/events would show up on the timeline viz
https://www.datadoghq.com/blog/continuous-profiler-timeline-view/
…lector tests fail
…belong with threading)
Co-authored-by: Taegyun Kim <[email protected]>
Co-authored-by: Taegyun Kim <[email protected]>
45abc7f to
f29be5c
Compare
@taegyunkim , as we've discussed offline, there's a bug in the Thread Timeline view that prevents Lock events form being displayed. They are being captured, however, as we've discovered. For more details, see this ticket: https://datadoghq.atlassian.net/browse/PROF-12837 However, I can demonstrate that
|

PROF-12721
Description
This PR adds profiling support for a new kind of synchronization mechanism: Reentrant Lock. A RLock is a lock that can be acquired by the same thread multiple times without blocking on itself. From the documentation:
This feature was identified as one of the most - low-hanging-fruits, since
RLocks are being used extensively in Python world.Changes
ThreadingRLockCollectorclass inthreading.pyprofiler.pytest_threading.pymodule has been updated to reuse existing tests for bothLockandRLockprimitives (via new inheritance)test_global_lockstest rewritten extensively to support the unit test code reuse betweenLockandRLock(effectively duplicating the existing extensiveLockunit tests forRLock... without the code duplication)Testing
Risks
none
Additional Notes